chore: remove `tracing::info` usage #578

dutterbutter · 2025-02-04T01:50:13Z

What 💻

Turns off tracing::info! in favour of shell wrapper and macro usage. A simplified version of Foundry's shell wrapper.
Removes the timestamp for warn, error, debug, trace logs

Why ✋

Clutters the node too much making it noisier then it needs to be.
Easier to add json support
Timestamp is not useful for a test node setting
Related to Proposal: Improved Logging and Flag Redesign for anvil-zksync #576 apart of the effort to improve debugging experience, Closes Refactor: Replace tracing::info! with stdout #435

Evidence 📷

Include screenshots, screen recordings, or console output here demonstrating that your changes work as intended

…-zksync into db/remove-tracing-info

Cargo.toml

spec-tests/src/patch.rs

crates/common/src/shell.rs

…-zksync into db/remove-tracing-info

dutterbutter · 2025-02-06T18:21:39Z

@itegulov based on the proposal feedback, I turned off tracing::info by default, and adjusted some existing log levels. I did so quite arbitrarily so please feel free to suggest changing the level or removing completely. We are still logging out tx summary / console logs by default but intend to update in #577.

For revert / halts and logs in formatter.rs those will be subsequently updated in #571 and #577.

popzxc

Mostly LGTM

popzxc · 2025-02-10T07:16:50Z

crates/common/Cargo.toml

+
+[dependencies]
+anstream.workspace = true
+anstyle.workspace = true


Nit: missing newline

popzxc · 2025-02-10T07:25:29Z

crates/common/src/shell.rs

+        let prefix = if self.should_color() {
+            format!("{}Warning:{} ", WARN, Reset)
+        } else {
+            "Warning: ".to_string()
+        };
+        self.println_err(&format!("{}{}", prefix, msg))


Nit (here and in other places): extra allocations seem unjustified, we could easily just write to stdout/stderr.
Not that it's a performance concern, just feels not very clean. In that regard, I like foundry approach more.

popzxc · 2025-02-10T07:26:50Z

crates/core/src/node/eth.rs

@@ -55,7 +56,7 @@ impl InMemoryNode {
                    message
                );

-                tracing::info!("{}", pretty_message.on_red());
+                sh_eprintln!("\n{}", pretty_message.on_red());


Here and in other places: why do we need \n to be inserted manually?

Just for readability, more opinionated than anything. For example, since we are still printing tx summary currently, without \n in some places you get:

✅ [SUCCESS] Hash: 0x9c159398838efc27c9b8e0f858d39914c2d57a28e264a21124898f7ce0f99973 Initiator: 0xbd29a1b981925b94eec5c4f1125af02a2ec4d1ca Payer: 0xbd29a1b981925b94eec5c4f1125af02a2ec4d1ca Gas Limit: 317_069 | Used: 317_069 | Refunded: 0 Paid: 0.0000143474 ETH (317069 gas * 0.04525000 gwei) Refunded: 0.0000000000 ETH execution reverted: Ownable: caller is not the owner Traces: [18748] RichAccount::validateTransaction(0x3a01cb7f742913bc3ad049e8d38aa733b6b5109900bfc32050b34553fcec9f54, 0xa4da2b8671d03015e54f04c404bcc833ad27ce876378f46c5de0f7fe0cede56a, (113, 310456771025820669616026695872740475403597889609 [3.104e47], 32774 [3.277e4], 1073938 [1.073e6], 50000 [5e4], 45250000 [4.525e7], 45250000 [4.525e7], 0, 4, 0, [0, 0, 0, 0], 0x9c4d535b0000000000000000000000000000000000000000000000000000000000000000010001556e69cb167b6cd0feb302b363b7045e5a8d960f60593983b2690bad39000000000000000000000000000000000000000000000000000000000000006000000000000000000000000000000000000000000000000000000000000000600000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000d48656c6c6f2c20776f726c642100000000000000000000000000000000000000, 0x633c8fc52cea7cb7d52edf9987fc2e090a39071e5f61cf81cadbf56653557d4f14fa7d4307f2164b37e852a04400db1165490f7d2febf7c6461fad44d186750f1c, [0x010001556e69cb167b6cd0feb302b363b7045e5a8d960f60593983b2690bad39], 0x, 0x)) └─ ← [Success] 202bcce700000000000000000000000000000000000000000000000000000000 [8691] RichAccount::payForTransaction(0x3a01cb7f742913bc3ad049e8d38aa733b6b5109900bfc32050b34553fcec9f54, 0xa4da2b8671d03015e54f04c404bcc833ad27ce876378f46c5de0f7fe0cede56a, (113, 310456771025820669616026695872740475403597889609 [3.104e47], 32774 [3.277e4], 1073938 [1.073e6], 50000 [5e4], 45250000 [4.525e7], 45250000 [4.525e7], 0, 4, 0, [0, 0, 0, 0], 0x9c4d535b0000000000000000000000000000000000000000000000000000000000000000010001556e69cb167b6cd0feb302b363b7045e5a8d960f60593983b2690bad39000000000000000000000000000000000000000000000000000000000000006000000000000000000000000000000000000000000000000000000000000000600000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000d48656c6c6f2c20776f726c642100000000000000000000000000000000000000, 0x633c8fc52cea7cb7d52edf9987fc2e090a39071e5f61cf81cadbf56653557d4f14fa7d4307f2164b37e852a04400db1165490f7d2febf7c6461fad44d186750f1c, [0x010001556e69cb167b6cd0feb302b363b7045e5a8d960f60593983b2690bad39], 0x, 0x)) └─ ← [Success] [43918] RichAccount::executeTransaction(0x3a01cb7f742913bc3ad049e8d38aa733b6b5109900bfc32050b34553fcec9f54, 0xa4da2b8671d03015e54f04c404bcc833ad27ce876378f46c5de0f7fe0cede56a, (113, 310456771025820669616026695872740475403597889609 [3.104e47], 32774 [3.277e4], 1073938 [1.073e6], 50000 [5e4], 45250000 [4.525e7], 45250000 [4.525e7], 0, 4, 0, [0, 0, 0, 0], 0x9c4d535b0000000000000000000000000000000000000000000000000000000000000000010001556e69cb167b6cd0feb302b363b7045e5a8d960f60593983b2690bad39000000000000000000000000000000000000000000000000000000000000006000000000000000000000000000000000000000000000000000000000000000600000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000d48656c6c6f2c20776f726c642100000000000000000000000000000000000000, 0x633c8fc52cea7cb7d52edf9987fc2e090a39071e5f61cf81cadbf56653557d4f14fa7d4307f2164b37e852a04400db1165490f7d2febf7c6461fad44d186750f1c, [0x010001556e69cb167b6cd0feb302b363b7045e5a8d960f60593983b2690bad39], 0x, 0x)) ├─ [12412] → new <unknown>@0x4b5df730c2e6b28e17013a1485e5d9bc41efe021 │ ├─ emit OwnershipTransferred(param0: 0x0000000000000000000000000000000000000000, param1: RichAccount: [0x36615Cf349d7F6344891B1e7CA7C72883F5dc049]) │ └─ ← [Success] 64 bytes of code └─ ← [Success] 00000000000000000000000000000000000000000000000000000000000000200000000000000000000000000000000000000000000000000000000000000000

itegulov

Looks good conceptually, some logs were misconverted though IMHO

itegulov · 2025-02-10T11:24:29Z

crates/config/src/config.rs

+        sh_println!("Genesis Timestamp");
+        sh_println!("========================");
+        sh_println!("{}", self.get_genesis_timestamp().to_string().green());
+        sh_println!("\n");


Something I have wanted to do for a while is to refactor this file to print using raw strings instead, like this:

sh_print!( r#" Genesis Timestamp ======================== {} "#, self.get_genesis_timestamp().to_string().green() );

The code indents won't be pretty but it will be easy to see what each table looks like (and ensure that fields are properly aligned etc). Can be done in a separate PR ofc

ahhh this is much better 👍

itegulov · 2025-02-10T11:37:54Z

crates/core/src/formatter.rs

+    sh_println!("\n{}  [{}] Hash: {:?}", emoji, status, tx.hash());
+    sh_println!("Initiator: {:?}", tx.initiator_account());
+    sh_println!("Payer: {:?}", tx.payer());
+    sh_println!(
        "Gas Limit: {} | Used: {} | Refunded: {}",
        to_human_size(tx.gas_limit()),
        to_human_size(used_gas),
        to_human_size(tx_result.refunds.gas_refunded.into())
    );
-    tracing::info!(
+    sh_println!(
        "Paid: {:.10} ETH ({} gas * {})",
        paid_in_eth,
        used_gas,
        format_gwei(l2_gas_price.into())
    );
-    tracing::info!("Refunded: {:.10} ETH", refunded_in_eth);
+    sh_println!("Refunded: {:.10} ETH", refunded_in_eth);


Same thing here potentially. Note: you can use variable in interpolation directly and named parameters like this: sh_println!("{argument}", argument = "test"). See fmt

itegulov · 2025-02-10T11:45:05Z

crates/core/src/node/in_memory_ext.rs

+        tracing::debug!(
+            "set code: address={:?}, bytecode_hash={:?}",
+            address,
+            BytecodeHash::for_bytecode(&bytecode).value()


The order was correct before, this is how you output structured logs/events in tracing. See docs

itegulov · 2025-02-10T11:45:17Z

crates/core/src/node/inner/blockchain.rs

+            latest_number,
+            latest_hash,
+            latest_batch_number,
+            latest_timestamp


itegulov · 2025-02-10T11:47:57Z

crates/core/src/node/inner/in_memory_inner.rs

                Err(Web3Error::SubmitTransactionError(pretty_message, data))
            }
            ExecutionResult::Halt { reason } => {
-                tracing::info!("{}", format!("Unable to estimate gas for the request with our suggested gas limit of {}. The transaction is most likely unexecutable. Breakdown of estimation:", suggested_gas_limit + overhead).red());
-                tracing::info!(
+                tracing::debug!("{}", format!("Unable to estimate gas for the request with our suggested gas limit of {}. The transaction is most likely unexecutable. Breakdown of estimation:", suggested_gas_limit + overhead).red());


Here and in other places: no need to colorize tracing logs, then format! arguments can be inlined

itegulov · 2025-02-10T11:49:46Z

crates/core/src/node/inner/node_executor.rs

@@ -111,7 +112,7 @@ impl NodeExecutor {
        // Reply to sender if we can, otherwise hold result for further processing
        let result = if let Some(reply) = reply {
            if let Err(result) = reply.send(result) {
-                tracing::info!("failed to reply as receiver has been dropped");
+                sh_eprintln!("failed to reply as receiver has been dropped");


I would leave reply failures as tracing logs. If receiver was dropped then it (likely) means network connection with users client (ethers, hardhat script etc) got severed for some reason. Not super actionable from user's side.

itegulov · 2025-02-10T11:51:36Z

crates/core/src/node/pool.rs

-                        "Failed to send transaction notification because channel is full",
+                    sh_warn!(
+                        "Failed to send transaction notification because channel is full: {}",
+                        tx_hash,


itegulov · 2025-02-10T11:54:58Z

crates/core/src/node/zks.rs

@@ -139,7 +139,6 @@ impl InMemoryNode {
        if let Some(bytecode) = self.storage.load_factory_dep_alt(hash).await? {
            return Ok(Some(bytecode));
        }
-        println!("Nope");


lol, this println sneaking through reminded me of below. IYKYK

dutterbutter added 3 commits February 3, 2025 19:42

chore: remove tracing::info in favour of pure stdout

36767a6

chore: linting

debc56d

chore: fix formatting

0d3b49f

dutterbutter marked this pull request as ready for review February 4, 2025 02:05

dutterbutter requested a review from a team as a code owner February 4, 2025 02:05

dutterbutter marked this pull request as draft February 4, 2025 13:48

dutterbutter added 5 commits February 4, 2025 10:02

feat: move to use shell io

32abbd8

feat: introduce shell io abstraction for logging

83e902d

Merge branch 'main' into db/remove-tracing-info

270831f

chore: remove clippy unused println

8903105

Merge branch 'db/remove-tracing-info' of github.com:matter-labs/anvil…

df52cfc

…-zksync into db/remove-tracing-info

dutterbutter mentioned this pull request Feb 4, 2025

Proposal: Improved Logging and Flag Redesign for anvil-zksync #576

Open

chore: linting

89e04dd

dutterbutter mentioned this pull request Feb 4, 2025

feat: introduces verbosity cli option with foundry-style traces #577

Draft

itegulov reviewed Feb 6, 2025

View reviewed changes

Cargo.toml Outdated Show resolved Hide resolved

spec-tests/src/patch.rs Outdated Show resolved Hide resolved

crates/common/src/shell.rs Outdated Show resolved Hide resolved

dutterbutter added 3 commits February 6, 2025 10:26

feat: make use of anstream and anystyle, remove use of atty

edb2789

chore: linting

82af8fe

Merge branch 'main' into db/remove-tracing-info

a1701ff

dutterbutter marked this pull request as ready for review February 6, 2025 16:39

dutterbutter requested review from itegulov and popzxc February 6, 2025 16:41

dutterbutter added 3 commits February 6, 2025 12:18

feat: turn tracing off by default, update messages

5e2e87d

Merge branch 'db/remove-tracing-info' of github.com:matter-labs/anvil…

fcba826

…-zksync into db/remove-tracing-info

chore: resolve conflicts

649e492

Merge branch 'main' into db/remove-tracing-info

b6c9d62

dutterbutter added the needs review 👓 PR requires a review label Feb 7, 2025

popzxc reviewed Feb 10, 2025

View reviewed changes

itegulov requested changes Feb 10, 2025

View reviewed changes

chore: make requested changes

9a8de7f

dutterbutter added 2 commits February 10, 2025 15:45

chore: update pool_rs

85d5c9e

chore: linting, fix formatting. Remove uneeded colorize

5508301

dutterbutter requested review from popzxc and itegulov February 10, 2025 22:16

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore: remove `tracing::info` usage #578

chore: remove `tracing::info` usage #578

dutterbutter commented Feb 4, 2025 •

edited

Loading

dutterbutter commented Feb 6, 2025 •

edited

Loading

popzxc left a comment

popzxc Feb 10, 2025

popzxc Feb 10, 2025

popzxc Feb 10, 2025

dutterbutter Feb 10, 2025

itegulov left a comment

itegulov Feb 10, 2025

dutterbutter Feb 10, 2025

itegulov Feb 10, 2025

itegulov Feb 10, 2025

itegulov Feb 10, 2025

itegulov Feb 10, 2025

itegulov Feb 10, 2025

itegulov Feb 10, 2025

itegulov Feb 10, 2025

chore: remove tracing::info usage #578

Are you sure you want to change the base?

chore: remove tracing::info usage #578

Conversation

dutterbutter commented Feb 4, 2025 • edited Loading

What 💻

Why ✋

Evidence 📷

dutterbutter commented Feb 6, 2025 • edited Loading

popzxc left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

itegulov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

chore: remove `tracing::info` usage #578

chore: remove `tracing::info` usage #578

dutterbutter commented Feb 4, 2025 •

edited

Loading

dutterbutter commented Feb 6, 2025 •

edited

Loading